chore: Improve Logging #634

n-o-u-r-h-a-n · 2025-10-27T13:09:46Z

Context

Printing useful Logs for AI SDK. The following example shows a tool execution:

16:25:13.299 INFO  [main] c.s.a.s.c.AiCoreServiceKeyAccessor : Found a service key in environment variable AICORE_SERVICE_KEY.
Using a service key is recommended for local testing only.
Bind the AI Core service to the application for productive usage.

16:25:13.530 INFO  [cloudsdk-executor-0] c.s.c.s.client.HttpClientFactory : loaded HttpClientFactory service providers: [com.sap.cloud.security.client.DefaultHttpClientFactory@1f53c0b1]
16:25:13.554 INFO  [cloudsdk-executor-0] c.s.cloud.security.servlet.MDCHelper : Correlation id (key=correlation_id) was not found in the MDC, generating a new one: f467fa77-7344-4336-a8bf-51407532499f
16:25:14.229 INFO  [main] c.sap.ai.sdk.core.DeploymentResolver : Found 32 deployments in resource group 'default'
16:25:14.229 INFO  [main] c.s.a.s.c.AiCoreServiceKeyAccessor : Found a service key in environment variable AICORE_SERVICE_KEY.
Using a service key is recommended for local testing only.
Bind the AI Core service to the application for productive usage.

16:25:14.236 DEBUG [main] c.s.a.s.o.OrchestrationHttpExecutor : [reqId=e94aa17b] Starting Orchestration synchronous request to /v2/completion, destination=https://<some-desination-uri>
16:25:16.433 DEBUG [main] c.s.a.s.c.c.ClientResponseHandler : [reqId=e94aa17b] Orchestration request completed successfully with duration=2101ms, size=1,6KB.
16:25:16.606 DEBUG [main] c.s.a.s.o.s.OrchestrationChatModel : Executing 2 tool call(s) - [getCurrentWeather, getCurrentWeather]
16:25:16.613 DEBUG [main] c.s.a.s.o.s.OrchestrationChatModel : Re-invoking LLM with tool execution results.
16:25:16.662 INFO  [main] c.s.a.s.c.AiCoreServiceKeyAccessor : Found a service key in environment variable AICORE_SERVICE_KEY.
Using a service key is recommended for local testing only.
Bind the AI Core service to the application for productive usage.

16:25:16.665 DEBUG [main] c.s.a.s.o.OrchestrationHttpExecutor : [reqId=53f857a7] Starting Orchestration synchronous request to /v2/completion, destination=https://<some-desination-uri>
16:25:18.174 DEBUG [main] c.s.a.s.c.c.ClientResponseHandler : [reqId=53f857a7] Orchestration request completed successfully with duration=1478ms, size=1,9KB.

Feature scope:

WARN logs removed : Credential type not found or not recognised in service binding.
- chore: WARN logs removed cloud-sdk-java#984
- chore: Reuse DotEnv instance and reduce log messages #635
Service Key logs are reduced to a minimum of 1 : Found a service key in environment variable AICORE_SERVICE_KEY.
- chore: Reuse DotEnv instance and reduce log messages #635
Useful Info logs added.
Useful Debug logs added.

Definition of Done

Functionality scope stated & covered
~~Tests cover the scope above~~
~~Error handling created / updated & covered by the tests above~~
~~Aligned changes with the JavaScript SDK~~
~~Documentation updated~~
~~Release notes updated~~

…gging

…w/appear in terminal for some reason.

CharlesDuboisSAP · 2025-10-27T14:09:26Z

logback.xml

+	</root>
+
+	<!--  <logger name="org.apache.hc.client5.http.wire" level="DEBUG"/>-->
+	<!--  <logger name="org.apache.http.wire" level="DEBUG"/>-->


Wire logs on unit tests finally

CharlesDuboisSAP · 2025-10-27T14:11:09Z

sample-code/spring-app/src/main/resources/logback-spring.xml

-        <root level="INFO"/>
-        <logger name="org.springframework.web" level="INFO"/>
-        <logger name="org.apache.hc.client5.http.wire" level="DEBUG"/>
-        <logger name="org.apache.http.wire" level="DEBUG"/>


logback.xml takes precedence

rpanackal · 2025-10-27T15:15:59Z

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

+      } else {
+        log.info("LLM request success");
+      }
+      log.debug("Response content:\n{}", content);


(Major)

I believe this needs to be removed. There was request from Joule on the same and we intentionally removed all request and response content logging in the past.

https://github.com/SAP/ai-sdk-java-backlog/issues/290

fix: [Core] Remove any logging of response request body #504

If there are no objections, I will remove this before the PR is merged

Agreeing with @rpanackal

Also some side-rules:

For highly repetitive messages and/or huge message footprints, use trace instead of debug.

Do not use new-lines \n in log messages.

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

newtork · 2025-10-28T14:48:30Z

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

+      final T value = objectMapper.readValue(content, successType);
+      val timeHeaders = response.getHeaders("x-upstream-service-time");
+      if (timeHeaders.length > 0) {
+        log.info("LLM request success with duration:{}", timeHeaders[0].getValue());


(Question/Minor)

Are all current and future messages to AI Core LLM requests? This is a generic/general response handling class 🤔

I wouldn't use "success", rather "completed". The user may have different understanding for "success".

Can we add HTTP response size to the message? e.g. 13KB
response.getEntity().getContentLength()

ClientResponseHandler is only invoked for openai and orchestration, and therefore "LLM requests" is not entirely wrong but ofc no guarantees for the future.

I have changed the request message to be more descriptive, including the response size.

pom.xml

CharlesDuboisSAP

.

foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

CharlesDuboisSAP · 2025-10-29T14:33:01Z

orchestration/src/main/java/com/sap/ai/sdk/orchestration/OrchestrationHttpExecutor.java

      throw new OrchestrationClientException(
          "Request to Orchestration service failed for " + path, e);
+    } finally {
+      MDC.clear();


If you have 2 requests running simultaneously, could the shorter one clear the context of the longer one?

MDC is thread local, so normally this shouldn't be a problem.

That said, we need to make sure that the MDC state is set and consumed per request level as the context is finally cleared after each request. A counter example would be setting the MDC in OrchestrationModuleConfig object and using it across multiple requests. Here the MDC context set in config creation is cleared on first request and cannot be expected to be available on subsequent requests.

I want to point out: If you are ever outside of the thread, you will lose the MDC parameters.
It's not obvious when/whether that happens. For example, if we ever decide to use Resilience (or any other form of TimeLimiter), then the approach will stop working I think.

sample-code/spring-app/src/main/resources/logback-spring.xml

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java

newtork · 2025-10-30T11:45:40Z

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

+    val sizeInfo = entityLength >= 0 ? String.format("%.1fKB", entityLength / 1024.0) : "unknown";
+    log.debug(
+        "[reqId={}] {} request completed successfully with duration={}, size={}.",
+        MDC.get("reqId"),


(Major/Question)

~~Why do you put MDC information here? They should be part of the general log pattern.~~
Edit: Normally these diagnostic context values are part of log patterns, instead of log messages. But I don't have a strong opinion against that.

What made you choose this String format with [...] and foo=bar? Are there any best practices that suggest that technical format? Do you expect tools to consume / evaluate the message?
Edit: We may have to define a so-called Architecture Decision Record to write down our decision what kind of pattern / format we prefer for variable based values.

Also please improve code format, this looks bad.
Edit: Have you considered using re-usable String constants? This would also help understanding these are dedicated diagnostic variables.

For the first two question

Edit: Normally these diagnostic context values are part of log patterns, instead of log messages.

My initial approach was applying the MDC on log patterns. But this lead to having awkward atifacts in all logs because there variable are not defined/expected to be available for them. Conditional patterns made the pattern itself unreadable and difficult to apply symbols to easily discern parts of the log.

What made you choose this String format with [...] and foo=bar? Are there any best practices that suggest that technical format? Do you expect tools to consume / evaluate the message?

I do not expect them to be machine readable. But purely thought of adopting a log format this is extendable incase we want to log additional information eg: "... status=OK". We choose purely descriptive messages instead. No strong opinion.

Have you considered using re-usable String constants? This would also help understanding these are dedicated diagnostic variables.

We can definitely add String constants.

...penai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java

…onmodels/openai/OpenAiChatCompletionResponse.java

n-o-u-r-h-a-n and others added 22 commits October 16, 2025 16:31

Reducing service key logs to minimum.

c1971e6

Some formatting

336f3a7

Custom Info Logs per LLM call

c4cbccc

Formatting the ClientResponseHandler.java class.

8dfb379

Merge branch 'main' into Improve-Logging

62cd10b

Merge branch 'refs/heads/main' into Improve-Logging

026d8e3

Removing unused dependency from grounding pom

e16b73d

Added Implicit Tool Calls Logging

65cd4a8

Added LLM Calls Logging

878229f

Some Formatting

52540e9

Merge branch 'main' into Improve-Logging

56c7c26

Some Formatting

14de56f

Some Formatting

5792a51

Some Formatting

5665644

formatting

51195fa

Merge remote-tracking branch 'origin/Improve-Logging' into Improve-Lo…

32bb886

…gging

Updating Pom Dependencies

2eb92da

service bindings static

7a37220

Merge remote-tracking branch 'origin/Improve-Logging' into Improve-Lo…

09bf293

…gging

fix tests

fcbd6fa

Added useful debug log but as an info one as log.debug() does not sho…

fe25e76

…w/appear in terminal for some reason.

logback config file

3541159

CharlesDuboisSAP reviewed Oct 27, 2025

View reviewed changes

CharlesDuboisSAP assigned CharlesDuboisSAP and n-o-u-r-h-a-n Oct 27, 2025

rpanackal reviewed Oct 27, 2025

View reviewed changes

newtork reviewed Oct 28, 2025

View reviewed changes

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java Outdated Show resolved Hide resolved

newtork reviewed Oct 28, 2025

View reviewed changes

pom.xml Show resolved Hide resolved

Per request logging update

649f265

Merge branch 'main' into Improve-Logging

2f61d28

CharlesDuboisSAP reviewed Oct 29, 2025

View reviewed changes

rpanackal added 2 commits October 29, 2025 16:06

Review suggestion

01661ae

fix minor

87e5ccb

newtork reviewed Oct 30, 2025

View reviewed changes

...penai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java Outdated Show resolved Hide resolved

newtork and others added 4 commits October 30, 2025 16:21

Update foundation-models/openai/src/main/java/com/sap/ai/sdk/foundati…

485ccc0

…onmodels/openai/OpenAiChatCompletionResponse.java

Formatting

ebcb1bd

Minor format

74094fb

Minor format

6e5fc2b

newtork previously approved these changes Oct 30, 2025

View reviewed changes

Fix PMD

1d94b4c

newtork dismissed their stale review via 1d94b4c October 30, 2025 15:35

newtork previously approved these changes Oct 30, 2025

View reviewed changes

newtork added 2 commits October 30, 2025 16:55

Merge remote-tracking branch 'origin/main' into Improve-Logging

a7b391b

Fix jacoco

4adb968

newtork dismissed their stale review via 4adb968 October 30, 2025 15:56

newtork approved these changes Oct 30, 2025

View reviewed changes

rpanackal merged commit bb64261 into main Oct 30, 2025
7 checks passed

rpanackal deleted the Improve-Logging branch October 30, 2025 16:17

chore: Improve Logging #634

chore: Improve Logging #634

Uh oh!

Conversation

n-o-u-r-h-a-n commented Oct 27, 2025 • edited by rpanackal Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Context

Feature scope:

Definition of Done

Uh oh!

CharlesDuboisSAP Oct 27, 2025

Choose a reason for hiding this comment

Uh oh!

CharlesDuboisSAP Oct 27, 2025

Choose a reason for hiding this comment

Uh oh!

rpanackal Oct 27, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

newtork Oct 28, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

newtork Oct 28, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rpanackal Oct 29, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

CharlesDuboisSAP left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

CharlesDuboisSAP Oct 29, 2025

Choose a reason for hiding this comment

Uh oh!

rpanackal Oct 29, 2025

Choose a reason for hiding this comment

Uh oh!

newtork Oct 30, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

newtork Oct 30, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rpanackal Oct 30, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

n-o-u-r-h-a-n commented Oct 27, 2025 •

edited by rpanackal

Loading

rpanackal Oct 27, 2025 •

edited

Loading

newtork Oct 28, 2025 •

edited

Loading

newtork Oct 28, 2025 •

edited

Loading

rpanackal Oct 29, 2025 •

edited

Loading

CharlesDuboisSAP left a comment •

edited

Loading

newtork Oct 30, 2025 •

edited

Loading